'''
An RPG Modification for Source games using Source Python.

    Copyright (C) 2012 Steven Hartin

    This program is free software: you can redistribute it and/or modify
    it under the terms of the GNU General Public License as published by
    the Free Software Foundation, either version 3 of the License, or
    (at your option) any later version.

    This program is distributed in the hope that it will be useful,
    but WITHOUT ANY WARRANTY; without even the implied warranty of
    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
    GNU General Public License for more details.

    You should have received a copy of the GNU General Public License
    along with this program.  If not, see <http://www.gnu.org/licenses/>.

Created on 3 Dec 2012

@author: Steven Hartin
@file: ../sourcerpg/logging/autologging.py
'''

import time
from functools import reduce
from operator import attrgetter

from paths import LOG_PATH

from sourcerpg.logging import Logger, loglevels

__all__ = ["AutoLogger", "USE_AUTO_LOGGER"]

# Amount of records to keep for the smoothed call time buffer
BUFFER_SIZE = 100

# Whether or not we're using auto logger
USE_AUTO_LOGGER = False

# Small amount to give every function call a 'time' (because floats can only
# be so accurate, and a function call may be quicker than a float's accuracy)
EPSILON = 0.000001


class AutoLogger(Logger):
    """A class to automatically hook all callable functions in a class

    The whole idea behind this is that we hook all functions in the global
    class namespace, and log the calls before and after the function. This
    will allow us to do some basic timing and debugging (if a crash occurs
    we should be able to see which function it crashed in etc).

    """
    class SavedFunctionHook(object):
        """Structure for holding both a name and address of a saved hook"""
        def __init__(self, cls, function_name, address, logger):
            """Constructor, hook the class method with logging.

            @param type cls The class instance to hook.
            @param str function_name The name of the function to hook
            @param callable address The address of the current function. This
                is used to restore the address when we unhook.
            @param Logger logger The logger object which has access to the log
                method

            """
            self.cls = cls
            self.function_name = function_name
            self.address = address
            self.times = [0.0] * BUFFER_SIZE
            self.index = 0
            self.average = 0.0
            self.logger = logger
            self._hook()

        def __del__(self):
            """Destructor, unhook the function"""
            self._unhook()

        def _hook(self):
            """Hook the function call in the class.

            The reason we have to return a reference to a local function is
            that we need access to the instance parameter. Since the 'this'
            parameter is passed explicitly, we need to control the path of this
            parameter and ensure that it is sent to the class method.

            Although this is kind of hacky, this should only be on in debug
            builds anyway.

            """
            def __return_func(inst, *args, **kwargs):
                """The actual function call hook.

                This is where the logging should occur. We want to perform some
                timing logging around the function call itself. This should
                help in the process of profiling the script. This should store
                the time to a running smoothed average buffer of the last few
                calls. We can then achieve an average from this and sort the
                function calls by execution times. This should help us track
                down the function calls with the longest execution time.

                """
                self.logger.log("Entering function: %s.%s" % (
                    self.cls.__name__, self.function_name),
                    loglevels.AUTOLOGGING)
                time_before_call = time.time()
                return_result = self.address(inst, *args, **kwargs)

                # Not all functions will register a valid time (see above),
                # make sure all calls take at least a 'minimum' execution time.
                time_taken = self.times[self.index] = \
                    max(time.time() - time_before_call, EPSILON)
                # Increase the current index, this is a running smooth buffer
                # to quantify a more accurate average
                self.index = (self.index + 1) % BUFFER_SIZE
                valid_times = list(filter(lambda x: x > 0.0, self.times))
                self.average = 0.0
                if len(valid_times) == 1:
                    self.average = valid_times[0]
                elif len(valid_times) > 1:
                    # Reduce can only work with 2 or more valid times
                    self.average = (reduce(lambda x, y: x + y, valid_times) /
                        len(valid_times))
                self.logger.log("Leaving function: %s.%s (%.2f secs)" % (
                    self.cls.__name__, self.function_name, time_taken),
                    loglevels.AUTOLOGGING)
                return return_result
            # Hook the class method
            setattr(self.cls, self.function_name, __return_func)

        def _unhook(self):
            """Restores the address of the class method back to the original"""
            setattr(self.cls, self.function_name, self.address)

    def __init__(self):
        super(AutoLogger, self).__init__()

        self.saved_function_addresses = dict()

    def __del__(self):
        self.unhook_all_functions()

    def hook_all_functions_for_class(self, cls):
        """Hooks all functions for a particular class

        Hooks all 'valid' functions for a class with the timing log calls
        around the execution. This should only be called once per class (not
        instance).

        A 'valid' method is one whose name isn't an internal name, and is a
        callable method. I'm not sure how this will work with 'static' methods,
        since I'm assuming in the hook that all methods will be called with
        an instance as the first parameter. Make sure that the class only
        contains valid non-static class methods.

        @param type cls The class to hook
        """
        if USE_AUTO_LOGGER is True:
            if not type(cls) is type:
                raise TypeError("Expected type 'type', instead received "
                                "type '%s'" % type(cls).__name__)
            members = vars(cls)
            addresses = self.saved_function_addresses[cls] = []

            for function_name, function_address in members.copy().items():
                # For every attribute in the class
                if function_name.startswith("__"):
                    # Don't hook internal functions
                    continue
                if type(function_address).__name__ != "function":
                    # Don't hook anything other than a function
                    continue
                hook = self.SavedFunctionHook(cls,
                                              function_name,
                                              function_address,
                                              self)
                addresses.append(hook)

    def unhook_all_functions(self):
        """Restore all hooked functions to their original addresses"""
        for cls, hooks in self.saved_function_addresses.items():
            # For every hooked class
            members = vars(cls)
            for saved_hook in hooks:
                # For every hooked function
                if not saved_hook.function_name in members:
                    continue
                members[saved_hook.function_name] = saved_hook.address

    def log_performance_stats(self):
        """Logs the average function call.

        This sorts all 'registered' function calls by average execution time
        in reverse order, and prints the results to a separate profiling log.

        """
        if USE_AUTO_LOGGER is True:
            times = sorted(self.saved_function_addresses,
                           key=attrgetter("average"),
                           reverse=True)
            total_time = reduce(
                lambda x, y: x + y,
                map(attrgetter("average"), self.saved_function_addresses))

            with open(LOG_PATH.joinpath("sourcerpg.profiling"),
                          "a") as handle:
                self.log("Profiling results", writetime=True)
                for cls in times:
                    max_time = max(cls.times)
                    min_time = min(filter(bool, cls.times))
                    self.log("%s.%s (%.2f%%) Avg(%.5f) Max(%.5f) Min(%.5f)" % (
                        cls.cls.__name__, cls.function_name,
                        cls.average / total_time * 100.0, cls.average,
                        max_time,
                        min_time),
                        stdout=handle,
                        level=loglevels.AUTOLOG)
